[INFO] fetching crate timesimp 1.0.0...
[INFO] testing timesimp-1.0.0 against try#0abe69e6c16114311cc2700e972492e64d69c28f for pr-154065-1
[INFO] extracting crate timesimp 1.0.0 into /workspace/builds/worker-6-tc2/source
[INFO] started tweaking crates.io crate timesimp 1.0.0
[INFO] removed 0 missing tests
[INFO] finished tweaking crates.io crate timesimp 1.0.0
[INFO] tweaked toml for crates.io crate timesimp 1.0.0 written to /workspace/builds/worker-6-tc2/source/Cargo.toml
[INFO] validating manifest of crates.io crate timesimp 1.0.0 on toolchain 0abe69e6c16114311cc2700e972492e64d69c28f
[INFO] running `Command { std: CARGO_HOME="/workspace/cargo-home" RUSTUP_HOME="/workspace/rustup-home" "/workspace/cargo-home/bin/cargo" "+0abe69e6c16114311cc2700e972492e64d69c28f" "metadata" "--manifest-path" "Cargo.toml" "--no-deps", kill_on_drop: false }`
[INFO] crate crates.io crate timesimp 1.0.0 already has a lockfile, it will not be regenerated
[INFO] running `Command { std: CARGO_HOME="/workspace/cargo-home" RUSTUP_HOME="/workspace/rustup-home" "/workspace/cargo-home/bin/cargo" "+0abe69e6c16114311cc2700e972492e64d69c28f" "fetch" "--manifest-path" "Cargo.toml", kill_on_drop: false }`
[INFO] running `Command { std: "docker" "create" "-v" "/var/lib/crater-agent-workspace/builds/worker-6-tc2/target:/opt/rustwide/target:rw,Z" "-v" "/var/lib/crater-agent-workspace/builds/worker-6-tc2/source:/opt/rustwide/workdir:ro,Z" "-v" "/var/lib/crater-agent-workspace/cargo-home:/opt/rustwide/cargo-home:ro,Z" "-v" "/var/lib/crater-agent-workspace/rustup-home:/opt/rustwide/rustup-home:ro,Z" "-e" "SOURCE_DIR=/opt/rustwide/workdir" "-e" "CARGO_TARGET_DIR=/opt/rustwide/target" "-e" "CARGO_HOME=/opt/rustwide/cargo-home" "-e" "RUSTUP_HOME=/opt/rustwide/rustup-home" "-w" "/opt/rustwide/workdir" "-m" "1610612736" "--user" "0:0" "--network" "none" "ghcr.io/rust-lang/crates-build-env/linux@sha256:d429b63d4308055ea97f60fb1d3dfca48854a00942f1bd2ad806beaf015945ec" "/opt/rustwide/cargo-home/bin/cargo" "+0abe69e6c16114311cc2700e972492e64d69c28f" "metadata" "--no-deps" "--format-version=1", kill_on_drop: false }`
[INFO] [stdout] e5c3fc800bcf6b753ad96e80433d7d58f093c37acc3a6d3a51366097beaaca1e
[INFO] running `Command { std: "docker" "start" "-a" "e5c3fc800bcf6b753ad96e80433d7d58f093c37acc3a6d3a51366097beaaca1e", kill_on_drop: false }`
[INFO] running `Command { std: "docker" "inspect" "e5c3fc800bcf6b753ad96e80433d7d58f093c37acc3a6d3a51366097beaaca1e", kill_on_drop: false }`
[INFO] running `Command { std: "docker" "rm" "-f" "e5c3fc800bcf6b753ad96e80433d7d58f093c37acc3a6d3a51366097beaaca1e", kill_on_drop: false }`
[INFO] [stdout] e5c3fc800bcf6b753ad96e80433d7d58f093c37acc3a6d3a51366097beaaca1e
[INFO] running `Command { std: "docker" "create" "-v" "/var/lib/crater-agent-workspace/builds/worker-6-tc2/target:/opt/rustwide/target:rw,Z" "-v" "/var/lib/crater-agent-workspace/builds/worker-6-tc2/source:/opt/rustwide/workdir:ro,Z" "-v" "/var/lib/crater-agent-workspace/cargo-home:/opt/rustwide/cargo-home:ro,Z" "-v" "/var/lib/crater-agent-workspace/rustup-home:/opt/rustwide/rustup-home:ro,Z" "-e" "SOURCE_DIR=/opt/rustwide/workdir" "-e" "CARGO_TARGET_DIR=/opt/rustwide/target" "-e" "CARGO_INCREMENTAL=0" "-e" "RUST_BACKTRACE=full" "-e" "RUSTFLAGS=--cap-lints=forbid" "-e" "RUSTDOCFLAGS=--cap-lints=forbid" "-e" "CARGO_HOME=/opt/rustwide/cargo-home" "-e" "RUSTUP_HOME=/opt/rustwide/rustup-home" "-w" "/opt/rustwide/workdir" "-m" "1610612736" "--user" "0:0" "--network" "none" "ghcr.io/rust-lang/crates-build-env/linux@sha256:d429b63d4308055ea97f60fb1d3dfca48854a00942f1bd2ad806beaf015945ec" "/opt/rustwide/cargo-home/bin/cargo" "+0abe69e6c16114311cc2700e972492e64d69c28f" "build" "--frozen" "--message-format=json", kill_on_drop: false }`
[INFO] [stdout] cc2f0105cada96a6efa9a2131bb677e740f1963226fd7659ad731542c7ec6400
[INFO] running `Command { std: "docker" "start" "-a" "cc2f0105cada96a6efa9a2131bb677e740f1963226fd7659ad731542c7ec6400", kill_on_drop: false }`
[INFO] [stderr]    Compiling proc-macro2 v1.0.94
[INFO] [stderr]    Compiling libc v0.2.171
[INFO] [stderr]    Compiling jiff v0.2.10
[INFO] [stderr]    Compiling quote v1.0.40
[INFO] [stderr]    Compiling syn v2.0.100
[INFO] [stderr]    Compiling getrandom v0.3.2
[INFO] [stderr]    Compiling rand_core v0.9.3
[INFO] [stderr]    Compiling rand_chacha v0.9.0
[INFO] [stderr]    Compiling rand v0.9.1
[INFO] [stderr]    Compiling thiserror-impl v2.0.12
[INFO] [stderr]    Compiling tracing-attributes v0.1.28
[INFO] [stderr]    Compiling tracing v0.1.41
[INFO] [stderr]    Compiling thiserror v2.0.12
[INFO] [stderr]    Compiling timesimp v1.0.0 (/opt/rustwide/workdir)
[INFO] [stderr]     Finished `dev` profile [unoptimized + debuginfo] target(s) in 11.99s
[INFO] running `Command { std: "docker" "inspect" "cc2f0105cada96a6efa9a2131bb677e740f1963226fd7659ad731542c7ec6400", kill_on_drop: false }`
[INFO] running `Command { std: "docker" "rm" "-f" "cc2f0105cada96a6efa9a2131bb677e740f1963226fd7659ad731542c7ec6400", kill_on_drop: false }`
[INFO] [stdout] cc2f0105cada96a6efa9a2131bb677e740f1963226fd7659ad731542c7ec6400
[INFO] running `Command { std: "docker" "create" "-v" "/var/lib/crater-agent-workspace/builds/worker-6-tc2/target:/opt/rustwide/target:rw,Z" "-v" "/var/lib/crater-agent-workspace/builds/worker-6-tc2/source:/opt/rustwide/workdir:ro,Z" "-v" "/var/lib/crater-agent-workspace/cargo-home:/opt/rustwide/cargo-home:ro,Z" "-v" "/var/lib/crater-agent-workspace/rustup-home:/opt/rustwide/rustup-home:ro,Z" "-e" "SOURCE_DIR=/opt/rustwide/workdir" "-e" "CARGO_TARGET_DIR=/opt/rustwide/target" "-e" "CARGO_INCREMENTAL=0" "-e" "RUST_BACKTRACE=full" "-e" "RUSTFLAGS=--cap-lints=forbid" "-e" "RUSTDOCFLAGS=--cap-lints=forbid" "-e" "CARGO_HOME=/opt/rustwide/cargo-home" "-e" "RUSTUP_HOME=/opt/rustwide/rustup-home" "-w" "/opt/rustwide/workdir" "-m" "1610612736" "--user" "0:0" "--network" "none" "ghcr.io/rust-lang/crates-build-env/linux@sha256:d429b63d4308055ea97f60fb1d3dfca48854a00942f1bd2ad806beaf015945ec" "/opt/rustwide/cargo-home/bin/cargo" "+0abe69e6c16114311cc2700e972492e64d69c28f" "test" "--frozen" "--no-run" "--message-format=json", kill_on_drop: false }`
[INFO] [stdout] 7b62e3880fe95b32ebd593ebd786f3c8ef555efa6b51eb3821c03b7a4a7f2ebb
[INFO] running `Command { std: "docker" "start" "-a" "7b62e3880fe95b32ebd593ebd786f3c8ef555efa6b51eb3821c03b7a4a7f2ebb", kill_on_drop: false }`
[INFO] [stderr]    Compiling libc v0.2.171
[INFO] [stderr]    Compiling cc v1.2.20
[INFO] [stderr]    Compiling tracing-core v0.1.33
[INFO] [stderr]    Compiling log v0.4.27
[INFO] [stderr]    Compiling openssl v0.10.72
[INFO] [stderr]    Compiling syn v2.0.100
[INFO] [stderr]    Compiling http-body v1.0.1
[INFO] [stderr]    Compiling bitflags v2.9.0
[INFO] [stderr]    Compiling serde v1.0.219
[INFO] [stderr]    Compiling thread_local v1.1.8
[INFO] [stderr]    Compiling http-body-util v0.1.3
[INFO] [stderr]    Compiling tracing-log v0.2.0
[INFO] [stderr]    Compiling tracing-subscriber v0.3.19
[INFO] [stderr]    Compiling parking_lot_core v0.9.10
[INFO] [stderr]    Compiling signal-hook-registry v1.4.5
[INFO] [stderr]    Compiling mio v1.0.3
[INFO] [stderr]    Compiling socket2 v0.5.9
[INFO] [stderr]    Compiling getrandom v0.3.2
[INFO] [stderr]    Compiling rand_core v0.9.3
[INFO] [stderr]    Compiling openssl-sys v0.9.107
[INFO] [stderr]    Compiling rand_chacha v0.9.0
[INFO] [stderr]    Compiling parking_lot v0.12.3
[INFO] [stderr]    Compiling rand v0.9.1
[INFO] [stderr]    Compiling native-tls v0.2.14
[INFO] [stderr]    Compiling serde_urlencoded v0.7.1
[INFO] [stderr]    Compiling synstructure v0.13.1
[INFO] [stderr]    Compiling zerofrom-derive v0.1.6
[INFO] [stderr]    Compiling yoke-derive v0.7.5
[INFO] [stderr]    Compiling zerovec-derive v0.10.3
[INFO] [stderr]    Compiling displaydoc v0.2.5
[INFO] [stderr]    Compiling tokio-macros v2.5.0
[INFO] [stderr]    Compiling icu_provider_macros v1.5.0
[INFO] [stderr]    Compiling tracing-attributes v0.1.28
[INFO] [stderr]    Compiling openssl-macros v0.1.1
[INFO] [stderr]    Compiling thiserror-impl v2.0.12
[INFO] [stderr]    Compiling tokio v1.44.2
[INFO] [stderr]    Compiling zerofrom v0.1.6
[INFO] [stderr]    Compiling thiserror v2.0.12
[INFO] [stderr]    Compiling yoke v0.7.5
[INFO] [stderr]    Compiling tracing v0.1.41
[INFO] [stderr]    Compiling zerovec v0.10.4
[INFO] [stderr]    Compiling timesimp v1.0.0 (/opt/rustwide/workdir)
[INFO] [stderr]    Compiling tinystr v0.7.6
[INFO] [stderr]    Compiling icu_collections v1.5.0
[INFO] [stderr]    Compiling icu_locid v1.5.0
[INFO] [stderr]    Compiling icu_provider v1.5.0
[INFO] [stderr]    Compiling icu_locid_transform v1.5.0
[INFO] [stderr]    Compiling icu_properties v1.5.1
[INFO] [stderr]    Compiling tokio-util v0.7.15
[INFO] [stderr]    Compiling tokio-native-tls v0.3.1
[INFO] [stderr]    Compiling tower v0.5.2
[INFO] [stderr]    Compiling icu_normalizer v1.5.0
[INFO] [stderr]    Compiling h2 v0.4.9
[INFO] [stderr]    Compiling idna_adapter v1.2.0
[INFO] [stderr]    Compiling idna v1.0.3
[INFO] [stderr]    Compiling url v2.5.4
[INFO] [stderr]    Compiling hyper v1.6.0
[INFO] [stderr]    Compiling hyper-util v0.1.11
[INFO] [stderr]    Compiling hyper-tls v0.6.0
[INFO] [stderr]    Compiling reqwest v0.12.15
[INFO] [stderr]     Finished `test` profile [unoptimized + debuginfo] target(s) in 42.51s
[INFO] running `Command { std: "docker" "inspect" "7b62e3880fe95b32ebd593ebd786f3c8ef555efa6b51eb3821c03b7a4a7f2ebb", kill_on_drop: false }`
[INFO] running `Command { std: "docker" "rm" "-f" "7b62e3880fe95b32ebd593ebd786f3c8ef555efa6b51eb3821c03b7a4a7f2ebb", kill_on_drop: false }`
[INFO] [stdout] 7b62e3880fe95b32ebd593ebd786f3c8ef555efa6b51eb3821c03b7a4a7f2ebb
[INFO] running `Command { std: "docker" "create" "-v" "/var/lib/crater-agent-workspace/builds/worker-6-tc2/target:/opt/rustwide/target:rw,Z" "-v" "/var/lib/crater-agent-workspace/builds/worker-6-tc2/source:/opt/rustwide/workdir:ro,Z" "-v" "/var/lib/crater-agent-workspace/cargo-home:/opt/rustwide/cargo-home:ro,Z" "-v" "/var/lib/crater-agent-workspace/rustup-home:/opt/rustwide/rustup-home:ro,Z" "-e" "SOURCE_DIR=/opt/rustwide/workdir" "-e" "CARGO_TARGET_DIR=/opt/rustwide/target" "-e" "CARGO_INCREMENTAL=0" "-e" "RUST_BACKTRACE=full" "-e" "RUSTFLAGS=--cap-lints=forbid" "-e" "RUSTDOCFLAGS=--cap-lints=forbid" "-e" "CARGO_HOME=/opt/rustwide/cargo-home" "-e" "RUSTUP_HOME=/opt/rustwide/rustup-home" "-w" "/opt/rustwide/workdir" "-m" "1610612736" "--user" "0:0" "--network" "none" "ghcr.io/rust-lang/crates-build-env/linux@sha256:d429b63d4308055ea97f60fb1d3dfca48854a00942f1bd2ad806beaf015945ec" "/opt/rustwide/cargo-home/bin/cargo" "+0abe69e6c16114311cc2700e972492e64d69c28f" "test" "--frozen", kill_on_drop: false }`
[INFO] [stdout] 19120db81d8a1a38732d42a9108bbb5ee1881eeba61799936b71c5cb6431180f
[INFO] running `Command { std: "docker" "start" "-a" "19120db81d8a1a38732d42a9108bbb5ee1881eeba61799936b71c5cb6431180f", kill_on_drop: false }`
[INFO] [stderr]     Finished `test` profile [unoptimized + debuginfo] target(s) in 0.28s
[INFO] [stderr]      Running unittests src/lib.rs (/opt/rustwide/target/debug/deps/timesimp-df612d235f3c5d21)
[INFO] [stdout] 
[INFO] [stdout] running 5 tests
[INFO] [stdout] test delta::tests::client_ahead_of_server ... ok
[INFO] [stdout] test delta::tests::client_behind_server ... ok
[INFO] [stdout] test delta::tests::client_equal_server ... ok
[INFO] [stdout] test delta::tests::clock_went_backwards ... ok
[INFO] [stdout] test delta::tests::with_sleep ... ok
[INFO] [stdout] 
[INFO] [stdout] test result: ok. 5 passed; 0 failed; 0 ignored; 0 measured; 0 filtered out; finished in 0.03s
[INFO] [stdout] 
[INFO] [stderr]      Running tests/client_server.rs (/opt/rustwide/target/debug/deps/client_server-33ede81700d42ab7)
[INFO] [stdout] 
[INFO] [stdout] running 10 tests
[INFO] [stdout] [2m2026-03-30T08:00:49.052136Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m starting delta collection [3msamples[0m[2m=[0m5 [3mcurrent_offset[0m[2m=[0m0s
[INFO] [stdout] [2m2026-03-30T08:00:49.052190Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m starting delta collection [3msamples[0m[2m=[0m5 [3mcurrent_offset[0m[2m=[0m0s
[INFO] [stdout] [2m2026-03-30T08:00:49.052832Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m0ns [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-03-30T08:00:49.052858Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m0ns [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-03-30T08:00:49.052241Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m starting delta collection [3msamples[0m[2m=[0m5 [3mcurrent_offset[0m[2m=[0m0s
[INFO] [stdout] [2m2026-03-30T08:00:49.052309Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m starting delta collection [3msamples[0m[2m=[0m5 [3mcurrent_offset[0m[2m=[0m0s
[INFO] [stdout] [2m2026-03-30T08:00:49.053087Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m0ns [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-03-30T08:00:49.052526Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m starting delta collection [3msamples[0m[2m=[0m5 [3mcurrent_offset[0m[2m=[0m0s
[INFO] [stdout] [2m2026-03-30T08:00:49.052633Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m starting delta collection [3msamples[0m[2m=[0m5 [3mcurrent_offset[0m[2m=[0m5s
[INFO] [stdout] [2m2026-03-30T08:00:49.053215Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m0ns [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-03-30T08:00:49.052747Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m starting delta collection [3msamples[0m[2m=[0m5 [3mcurrent_offset[0m[2m=[0m0s
[INFO] [stdout] [2m2026-03-30T08:00:49.053240Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m0ns [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-03-30T08:00:49.053257Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m0ns [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-03-30T08:00:49.053265Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m0ns [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-03-30T08:00:49.053299Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m starting delta collection [3msamples[0m[2m=[0m5 [3mcurrent_offset[0m[2m=[0m5s ago
[INFO] [stdout] [2m2026-03-30T08:00:49.053328Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m0ns [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-03-30T08:00:49.054732Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m starting delta collection [3msamples[0m[2m=[0m5 [3mcurrent_offset[0m[2m=[0m0s
[INFO] [stdout] [2m2026-03-30T08:00:49.054783Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m0ns [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-03-30T08:00:49.060075Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-03-30T08:00:49.054566117Z, server: 2026-03-30T08:00:49.058595295Z } [3mcurrent[0m[2m=[0m2026-03-30T08:00:49.059740935Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m2ms 587µs 409ns [3mlocal_at_midpoint[0m[2m=[0m2026-03-30T08:00:49.057153526Z [3mdelta[0m[2m=[0m1ms 441µs 769ns
[INFO] [stdout] [2m2026-03-30T08:00:49.060223Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m2.587409ms [3mdelta[0m[2m=[0m1ms 441µs 769ns
[INFO] [stdout] [2m2026-03-30T08:00:49.060279Z[0m [34mDEBUG[0m [2mtimesimp[0m[2m:[0m no offset stored, storing initial delta [3moffset[0m[2m=[0m1ms 441µs 769ns
[INFO] [stdout] [2m2026-03-30T08:00:49.060330Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m717.937327ms [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-03-30T08:00:49.073730Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m starting delta collection [3msamples[0m[2m=[0m5 [3mcurrent_offset[0m[2m=[0m0s
[INFO] [stdout] [2m2026-03-30T08:00:49.073881Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m0ns [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-03-30T08:00:49.074840Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-03-30T08:00:49.054094417Z, server: 2026-03-30T08:00:54.064308474Z } [3mcurrent[0m[2m=[0m2026-03-30T08:00:49.074596321Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m10ms 250µs 952ns [3mlocal_at_midpoint[0m[2m=[0m2026-03-30T08:00:49.064345369Z [3mdelta[0m[2m=[0m4s 999ms 963µs 105ns
[INFO] [stdout] [2m2026-03-30T08:00:49.076499Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m10.250952ms [3mdelta[0m[2m=[0m4s 999ms 963µs 105ns
[INFO] [stdout] [2m2026-03-30T08:00:49.076104Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-03-30T08:00:49.054682336Z, server: 2026-03-30T08:00:54.065819004Z } [3mcurrent[0m[2m=[0m2026-03-30T08:00:49.075912771Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m10ms 615µs 217ns [3mlocal_at_midpoint[0m[2m=[0m2026-03-30T08:00:49.065297553Z [3mdelta[0m[2m=[0m5s 521µs 451ns
[INFO] [stdout] [2m2026-03-30T08:00:49.076671Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m10.615217ms [3mdelta[0m[2m=[0m5s 521µs 451ns
[INFO] [stdout] [2m2026-03-30T08:00:49.076745Z[0m [34mDEBUG[0m [2mtimesimp[0m[2m:[0m no offset stored, storing initial delta [3moffset[0m[2m=[0m5s 521µs 451ns
[INFO] [stdout] [2m2026-03-30T08:00:49.076817Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m1.909529395s [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-03-30T08:00:49.076790Z[0m [34mDEBUG[0m [2mtimesimp[0m[2m:[0m no offset stored, storing initial delta [3moffset[0m[2m=[0m4s 999ms 963µs 105ns
[INFO] [stdout] [2m2026-03-30T08:00:49.076966Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m1.709305312s [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-03-30T08:00:49.076901Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-03-30T08:00:49.054467766Z, server: 2026-03-30T08:00:44.065649374Z } [3mcurrent[0m[2m=[0m2026-03-30T08:00:49.076796041Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m11ms 164µs 137ns [3mlocal_at_midpoint[0m[2m=[0m2026-03-30T08:00:49.065631903Z [3mdelta[0m[2m=[0m4s 999ms 982µs 529ns ago
[INFO] [stdout] [2m2026-03-30T08:00:49.077075Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m11.164137ms [3mdelta[0m[2m=[0m4s 999ms 982µs 529ns ago
[INFO] [stdout] [2m2026-03-30T08:00:49.077100Z[0m [34mDEBUG[0m [2mtimesimp[0m[2m:[0m no offset stored, storing initial delta [3moffset[0m[2m=[0m4s 999ms 982µs 529ns ago
[INFO] [stdout] [2m2026-03-30T08:00:49.077114Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m558.275674ms [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-03-30T08:00:49.078592Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-03-30T08:00:49.054470846Z, server: 2026-03-30T08:00:49.065649334Z } [3mcurrent[0m[2m=[0m2026-03-30T08:00:49.078476051Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m12ms 2µs 602ns [3mlocal_at_midpoint[0m[2m=[0m2026-03-30T08:00:49.066473448Z [3mdelta[0m[2m=[0m824µs 114ns ago
[INFO] [stdout] [2m2026-03-30T08:00:49.078663Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m12.002602ms [3mdelta[0m[2m=[0m824µs 114ns ago
[INFO] [stdout] [2m2026-03-30T08:00:49.078683Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m1.98178958s [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-03-30T08:00:49.079584Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-03-30T08:00:49.054523157Z, server: 2026-03-30T08:00:49.065665024Z } [3mcurrent[0m[2m=[0m2026-03-30T08:00:49.07947348Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m12ms 475µs 161ns [3mlocal_at_midpoint[0m[2m=[0m2026-03-30T08:00:49.066998318Z [3mdelta[0m[2m=[0m1ms 333µs 294ns ago
[INFO] [stdout] [2m2026-03-30T08:00:49.079656Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m12.475161ms [3mdelta[0m[2m=[0m1ms 333µs 294ns ago
[INFO] [stdout] [2m2026-03-30T08:00:49.079677Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m805.930697ms [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-03-30T08:00:49.084748Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-03-30T08:00:49.057551505Z, server: 2026-03-30T08:00:54.070532742Z } [3mcurrent[0m[2m=[0m2026-03-30T08:00:49.084529589Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m13ms 489µs 42ns [3mlocal_at_midpoint[0m[2m=[0m2026-03-30T08:00:49.071040547Z [3mdelta[0m[2m=[0m4s 999ms 492µs 195ns
[INFO] [stdout] [2m2026-03-30T08:00:49.084852Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m13.489042ms [3mdelta[0m[2m=[0m4s 999ms 492µs 195ns
[INFO] [stdout] [2m2026-03-30T08:00:49.084875Z[0m [34mDEBUG[0m [2mtimesimp[0m[2m:[0m no offset stored, storing initial delta [3moffset[0m[2m=[0m4s 999ms 492µs 195ns
[INFO] [stdout] [2m2026-03-30T08:00:49.084889Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m559.305579ms [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-03-30T08:00:49.091757Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-03-30T08:00:49.075147271Z, server: 2026-03-30T08:00:54.083321759Z } [3mcurrent[0m[2m=[0m2026-03-30T08:00:49.091530037Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m8ms 191µs 383ns [3mlocal_at_midpoint[0m[2m=[0m2026-03-30T08:00:49.083338654Z [3mdelta[0m[2m=[0m4s 999ms 983µs 105ns
[INFO] [stdout] [2m2026-03-30T08:00:49.091849Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m8.191383ms [3mdelta[0m[2m=[0m4s 999ms 983µs 105ns
[INFO] [stdout] [2m2026-03-30T08:00:49.091873Z[0m [34mDEBUG[0m [2mtimesimp[0m[2m:[0m no offset stored, storing initial delta [3moffset[0m[2m=[0m4s 999ms 983µs 105ns
[INFO] [stdout] [2m2026-03-30T08:00:49.091889Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m165.660173ms [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-03-30T08:00:49.256495Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-03-30T08:00:49.054473146Z, server: 2026-03-30T08:00:49.154833541Z } [3mcurrent[0m[2m=[0m2026-03-30T08:00:49.256247926Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m100ms 887µs 390ns [3mlocal_at_midpoint[0m[2m=[0m2026-03-30T08:00:49.155360536Z [3mdelta[0m[2m=[0m526µs 995ns ago
[INFO] [stdout] [2m2026-03-30T08:00:49.256928Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m100.88739ms [3mdelta[0m[2m=[0m526µs 995ns ago
[INFO] [stdout] [2m2026-03-30T08:00:49.257507Z[0m [34mDEBUG[0m [2mtimesimp[0m[2m:[0m no offset stored, storing initial delta [3moffset[0m[2m=[0m526µs 995ns ago
[INFO] [stdout] [2m2026-03-30T08:00:49.257621Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m1.59739103s [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-03-30T08:00:49.279272Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-03-30T08:00:49.262543455Z, server: 2026-03-30T08:00:54.270539713Z } [3mcurrent[0m[2m=[0m2026-03-30T08:00:49.279066841Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m8ms 261µs 693ns [3mlocal_at_midpoint[0m[2m=[0m2026-03-30T08:00:49.270805148Z [3mdelta[0m[2m=[0m4s 999ms 734µs 565ns
[INFO] [stdout] [2m2026-03-30T08:00:49.279392Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m8.261693ms [3mdelta[0m[2m=[0m4s 999ms 734µs 565ns
[INFO] [stdout] [2m2026-03-30T08:00:49.279440Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m383.267867ms [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-03-30T08:00:49.658446Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-03-30T08:00:49.635791992Z, server: 2026-03-30T08:00:44.647006569Z } [3mcurrent[0m[2m=[0m2026-03-30T08:00:49.658220907Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m11ms 214µs 457ns [3mlocal_at_midpoint[0m[2m=[0m2026-03-30T08:00:49.647006449Z [3mdelta[0m[2m=[0m4s 999ms 999µs 880ns ago
[INFO] [stdout] [2m2026-03-30T08:00:49.658545Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m11.214457ms [3mdelta[0m[2m=[0m4s 999ms 999µs 880ns ago
[INFO] [stdout] [2m2026-03-30T08:00:49.658571Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m1.55496664s [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-03-30T08:00:49.668207Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-03-30T08:00:49.64568696Z, server: 2026-03-30T08:00:54.656860617Z } [3mcurrent[0m[2m=[0m2026-03-30T08:00:49.668023894Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m11ms 168µs 467ns [3mlocal_at_midpoint[0m[2m=[0m2026-03-30T08:00:49.656855427Z [3mdelta[0m[2m=[0m5s 5µs 190ns
[INFO] [stdout] [2m2026-03-30T08:00:49.668304Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m11.168467ms [3mdelta[0m[2m=[0m5s 5µs 190ns
[INFO] [stdout] [2m2026-03-30T08:00:49.668328Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m1.065188539s [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-03-30T08:00:49.684253Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-03-30T08:00:49.664144605Z, server: 2026-03-30T08:00:54.674843892Z } [3mcurrent[0m[2m=[0m2026-03-30T08:00:49.68406312Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m9ms 959µs 257ns [3mlocal_at_midpoint[0m[2m=[0m2026-03-30T08:00:49.674103862Z [3mdelta[0m[2m=[0m5s 740µs 30ns
[INFO] [stdout] [2m2026-03-30T08:00:49.684369Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m9.959257ms [3mdelta[0m[2m=[0m5s 740µs 30ns
[INFO] [stdout] [2m2026-03-30T08:00:49.684393Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m1.600098318s [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-03-30T08:00:49.782332Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-03-30T08:00:49.779685117Z, server: 2026-03-30T08:00:49.780827276Z } [3mcurrent[0m[2m=[0m2026-03-30T08:00:49.782045756Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m1ms 180µs 319ns [3mlocal_at_midpoint[0m[2m=[0m2026-03-30T08:00:49.780865436Z [3mdelta[0m[2m=[0m38µs 160ns ago
[INFO] [stdout] [2m2026-03-30T08:00:49.782456Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m1.180319ms [3mdelta[0m[2m=[0m38µs 160ns ago
[INFO] [stdout] [2m2026-03-30T08:00:49.782480Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m1.87904718s [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-03-30T08:00:49.909248Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-03-30T08:00:49.88654416Z, server: 2026-03-30T08:00:49.897774367Z } [3mcurrent[0m[2m=[0m2026-03-30T08:00:49.909014964Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m11ms 235µs 402ns [3mlocal_at_midpoint[0m[2m=[0m2026-03-30T08:00:49.897779562Z [3mdelta[0m[2m=[0m5µs 195ns ago
[INFO] [stdout] [2m2026-03-30T08:00:49.909370Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m11.235402ms [3mdelta[0m[2m=[0m5µs 195ns ago
[INFO] [stdout] [2m2026-03-30T08:00:49.909400Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m1.834390146s [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-03-30T08:00:50.758961Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-03-30T08:00:50.734708619Z, server: 2026-03-30T08:00:55.747543146Z } [3mcurrent[0m[2m=[0m2026-03-30T08:00:50.758767943Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m12ms 29µs 662ns [3mlocal_at_midpoint[0m[2m=[0m2026-03-30T08:00:50.746738281Z [3mdelta[0m[2m=[0m5s 804µs 865ns
[INFO] [stdout] [2m2026-03-30T08:00:50.759082Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m12.029662ms [3mdelta[0m[2m=[0m5s 804µs 865ns
[INFO] [stdout] [2m2026-03-30T08:00:50.759156Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m929.685957ms [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-03-30T08:00:50.801352Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-03-30T08:00:50.787706256Z, server: 2026-03-30T08:00:55.794927225Z } [3mcurrent[0m[2m=[0m2026-03-30T08:00:50.801148913Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m6ms 721µs 328ns [3mlocal_at_midpoint[0m[2m=[0m2026-03-30T08:00:50.794427584Z [3mdelta[0m[2m=[0m5s 499µs 641ns
[INFO] [stdout] [2m2026-03-30T08:00:50.801617Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m6.721328ms [3mdelta[0m[2m=[0m5s 499µs 641ns
[INFO] [stdout] [2m2026-03-30T08:00:50.801727Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m463.139219ms [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-03-30T08:00:50.958878Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-03-30T08:00:49.054093786Z, server: 2026-03-30T08:00:50.00672047Z } [3mcurrent[0m[2m=[0m2026-03-30T08:00:50.958644454Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m952ms 275µs 334ns [3mlocal_at_midpoint[0m[2m=[0m2026-03-30T08:00:50.00636912Z [3mdelta[0m[2m=[0m351µs 350ns
[INFO] [stdout] [2m2026-03-30T08:00:50.958991Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m952.275334ms [3mdelta[0m[2m=[0m351µs 350ns
[INFO] [stdout] [2m2026-03-30T08:00:50.959016Z[0m [34mDEBUG[0m [2mtimesimp[0m[2m:[0m no offset stored, storing initial delta [3moffset[0m[2m=[0m351µs 350ns
[INFO] [stdout] [2m2026-03-30T08:00:50.959030Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m594.364µs [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-03-30T08:00:51.010823Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-03-30T08:00:50.988176146Z, server: 2026-03-30T08:00:55.999382594Z } [3mcurrent[0m[2m=[0m2026-03-30T08:00:51.010618961Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m11ms 221µs 407ns [3mlocal_at_midpoint[0m[2m=[0m2026-03-30T08:00:50.999397553Z [3mdelta[0m[2m=[0m4s 999ms 985µs 41ns
[INFO] [stdout] [2m2026-03-30T08:00:51.010920Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m11.221407ms [3mdelta[0m[2m=[0m4s 999ms 985µs 41ns
[INFO] [stdout] [2m2026-03-30T08:00:51.010944Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m1.2079744s [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-03-30T08:00:51.069843Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-03-30T08:00:50.865896407Z, server: 2026-03-30T08:00:50.967274512Z } [3mcurrent[0m[2m=[0m2026-03-30T08:00:51.069629866Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m101ms 866µs 729ns [3mlocal_at_midpoint[0m[2m=[0m2026-03-30T08:00:50.967763136Z [3mdelta[0m[2m=[0m488µs 624ns ago
[INFO] [stdout] [2m2026-03-30T08:00:51.069947Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m101.866729ms [3mdelta[0m[2m=[0m488µs 624ns ago
[INFO] [stdout] [2m2026-03-30T08:00:51.069973Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m1.506607843s [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-03-30T08:00:51.083084Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-03-30T08:00:51.061534178Z, server: 2026-03-30T08:00:51.071688556Z } [3mcurrent[0m[2m=[0m2026-03-30T08:00:51.082888073Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m10ms 676µs 947ns [3mlocal_at_midpoint[0m[2m=[0m2026-03-30T08:00:51.072211125Z [3mdelta[0m[2m=[0m522µs 569ns ago
[INFO] [stdout] [2m2026-03-30T08:00:51.083182Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m10.676947ms [3mdelta[0m[2m=[0m522µs 569ns ago
[INFO] [stdout] [2m2026-03-30T08:00:51.083207Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m1.096352744s [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-03-30T08:00:51.237602Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-03-30T08:00:51.2148099Z, server: 2026-03-30T08:00:46.226037707Z } [3mcurrent[0m[2m=[0m2026-03-30T08:00:51.237392305Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m11ms 291µs 202ns [3mlocal_at_midpoint[0m[2m=[0m2026-03-30T08:00:51.226101102Z [3mdelta[0m[2m=[0m5s 63µs 395ns ago
[INFO] [stdout] [2m2026-03-30T08:00:51.237714Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m11.291202ms [3mdelta[0m[2m=[0m5s 63µs 395ns ago
[INFO] [stdout] [2m2026-03-30T08:00:51.237738Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m728.504161ms [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-03-30T08:00:51.289730Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-03-30T08:00:51.266684987Z, server: 2026-03-30T08:00:56.277900834Z } [3mcurrent[0m[2m=[0m2026-03-30T08:00:51.289531002Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m11ms 423µs 7ns [3mlocal_at_midpoint[0m[2m=[0m2026-03-30T08:00:51.278107994Z [3mdelta[0m[2m=[0m4s 999ms 792µs 840ns
[INFO] [stdout] [2m2026-03-30T08:00:51.289830Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m11.423007ms [3mdelta[0m[2m=[0m4s 999ms 792µs 840ns
[INFO] [stdout] [2m2026-03-30T08:00:51.289852Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m963.893421ms [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-03-30T08:00:51.296313Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-03-30T08:00:51.285710613Z, server: 2026-03-30T08:00:56.290917321Z } [3mcurrent[0m[2m=[0m2026-03-30T08:00:51.29612016Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m5ms 204µs 773ns [3mlocal_at_midpoint[0m[2m=[0m2026-03-30T08:00:51.290915386Z [3mdelta[0m[2m=[0m5s 1µs 935ns
[INFO] [stdout] [2m2026-03-30T08:00:51.296433Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m5.204773ms [3mdelta[0m[2m=[0m5s 1µs 935ns
[INFO] [stdout] [2m2026-03-30T08:00:51.296458Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m56.779888ms [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-03-30T08:00:51.366498Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-03-30T08:00:51.353838726Z, server: 2026-03-30T08:00:56.360055864Z } [3mcurrent[0m[2m=[0m2026-03-30T08:00:51.366264553Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m6ms 212µs 913ns [3mlocal_at_midpoint[0m[2m=[0m2026-03-30T08:00:51.360051639Z [3mdelta[0m[2m=[0m5s 4µs 225ns
[INFO] [stdout] [2m2026-03-30T08:00:51.366599Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m6.212913ms [3mdelta[0m[2m=[0m5s 4µs 225ns
[INFO] [stdout] [2m2026-03-30T08:00:51.366634Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m response deltas sorted by latency [3mdeltas[0m[2m=[0m[5000.001935, 5000.004225, 4999.983105, 4999.734565, 5000.74003]
[INFO] [stdout] [2m2026-03-30T08:00:51.366655Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m statistics about response deltas [3mmedian[0m[2m=[0m4999.983105 [3mmean[0m[2m=[0m5000.092772 [3mvariance[0m[2m=[0m0.14384348902001365 [3mstddev[0m[2m=[0m0.3792670418320232
[INFO] [stdout] [2m2026-03-30T08:00:51.366679Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m eliminated outliers [3minliers[0m[2m=[0m[5000.001935, 5000.004225, 4999.983105, 4999.734565]
[INFO] [stdout] [2m2026-03-30T08:00:51.366694Z[0m [34mDEBUG[0m [2mtimesimp[0m[2m:[0m storing calculated offset [3moffset[0m[2m=[0m4s 999ms 930µs
[INFO] [stdout] test high_jitter ... ok
[INFO] [stdout] [2m2026-03-30T08:00:51.665150Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-03-30T08:00:51.662706039Z, server: 2026-03-30T08:00:51.663851339Z } [3mcurrent[0m[2m=[0m2026-03-30T08:00:51.664977838Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m1ms 135µs 899ns [3mlocal_at_midpoint[0m[2m=[0m2026-03-30T08:00:51.663841938Z [3mdelta[0m[2m=[0m9µs 401ns
[INFO] [stdout] [2m2026-03-30T08:00:51.665237Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m1.135899ms [3mdelta[0m[2m=[0m9µs 401ns
[INFO] [stdout] [2m2026-03-30T08:00:51.665258Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m1.702121374s [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-03-30T08:00:51.718755Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-03-30T08:00:51.692564922Z, server: 2026-03-30T08:00:56.703808779Z } [3mcurrent[0m[2m=[0m2026-03-30T08:00:51.718541755Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m12ms 988µs 416ns [3mlocal_at_midpoint[0m[2m=[0m2026-03-30T08:00:51.705553338Z [3mdelta[0m[2m=[0m4s 998ms 255µs 441ns
[INFO] [stdout] [2m2026-03-30T08:00:51.718857Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m12.988416ms [3mdelta[0m[2m=[0m4s 998ms 255µs 441ns
[INFO] [stdout] [2m2026-03-30T08:00:51.718880Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m113.105251ms [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-03-30T08:00:51.767986Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-03-30T08:00:51.744594019Z, server: 2026-03-30T08:00:51.756543596Z } [3mcurrent[0m[2m=[0m2026-03-30T08:00:51.767774963Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m11ms 590µs 472ns [3mlocal_at_midpoint[0m[2m=[0m2026-03-30T08:00:51.756184491Z [3mdelta[0m[2m=[0m359µs 105ns
[INFO] [stdout] [2m2026-03-30T08:00:51.768089Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m11.590472ms [3mdelta[0m[2m=[0m359µs 105ns
[INFO] [stdout] [2m2026-03-30T08:00:51.768113Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m954.165869ms [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-03-30T08:00:51.857151Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-03-30T08:00:51.834533656Z, server: 2026-03-30T08:00:56.845754664Z } [3mcurrent[0m[2m=[0m2026-03-30T08:00:51.856964091Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m11ms 215µs 217ns [3mlocal_at_midpoint[0m[2m=[0m2026-03-30T08:00:51.845748873Z [3mdelta[0m[2m=[0m5s 5µs 791ns
[INFO] [stdout] [2m2026-03-30T08:00:51.857247Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m11.215217ms [3mdelta[0m[2m=[0m5s 5µs 791ns
[INFO] [stdout] [2m2026-03-30T08:00:51.857274Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m response deltas sorted by latency [3mdeltas[0m[2m=[0m[5000.00519, 5000.005791, 5000.804865, 4998.255441, 4999.492195]
[INFO] [stdout] [2m2026-03-30T08:00:51.857294Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m statistics about response deltas [3mmedian[0m[2m=[0m5000.804865 [3mmean[0m[2m=[0m4999.7126964 [3mvariance[0m[2m=[0m0.8841258424115951 [3mstddev[0m[2m=[0m0.9402796618089722
[INFO] [stdout] [2m2026-03-30T08:00:51.857322Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m eliminated outliers [3minliers[0m[2m=[0m[5000.00519, 5000.005791, 5000.804865]
[INFO] [stdout] [2m2026-03-30T08:00:51.857336Z[0m [34mDEBUG[0m [2mtimesimp[0m[2m:[0m storing calculated offset [3moffset[0m[2m=[0m5s 271µs
[INFO] [stdout] test server_offset_positive ... ok
[INFO] [stdout] [2m2026-03-30T08:00:51.989341Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-03-30T08:00:51.966704014Z, server: 2026-03-30T08:00:46.977927461Z } [3mcurrent[0m[2m=[0m2026-03-30T08:00:51.989147318Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m11ms 221µs 652ns [3mlocal_at_midpoint[0m[2m=[0m2026-03-30T08:00:51.977925666Z [3mdelta[0m[2m=[0m4s 999ms 998µs 205ns ago
[INFO] [stdout] [2m2026-03-30T08:00:51.989653Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m11.221652ms [3mdelta[0m[2m=[0m4s 999ms 998µs 205ns ago
[INFO] [stdout] [2m2026-03-30T08:00:51.989725Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m247.773343ms [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-03-30T08:00:52.204954Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-03-30T08:00:52.18169324Z, server: 2026-03-30T08:00:52.194535167Z } [3mcurrent[0m[2m=[0m2026-03-30T08:00:52.204760435Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m11ms 533µs 597ns [3mlocal_at_midpoint[0m[2m=[0m2026-03-30T08:00:52.193226837Z [3mdelta[0m[2m=[0m1ms 308µs 330ns
[INFO] [stdout] [2m2026-03-30T08:00:52.205062Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m11.533597ms [3mdelta[0m[2m=[0m1ms 308µs 330ns
[INFO] [stdout] [2m2026-03-30T08:00:52.205087Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m896.624385ms [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-03-30T08:00:52.242293Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-03-30T08:00:52.220689611Z, server: 2026-03-30T08:00:57.231909588Z } [3mcurrent[0m[2m=[0m2026-03-30T08:00:52.242099345Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m10ms 704µs 867ns [3mlocal_at_midpoint[0m[2m=[0m2026-03-30T08:00:52.231394478Z [3mdelta[0m[2m=[0m5s 515µs 110ns
[INFO] [stdout] [2m2026-03-30T08:00:52.242387Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m10.704867ms [3mdelta[0m[2m=[0m5s 515µs 110ns
[INFO] [stdout] [2m2026-03-30T08:00:52.242411Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m382.059805ms [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-03-30T08:00:52.262724Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-03-30T08:00:52.239233446Z, server: 2026-03-30T08:00:47.250502533Z } [3mcurrent[0m[2m=[0m2026-03-30T08:00:52.26253707Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m11ms 651µs 812ns [3mlocal_at_midpoint[0m[2m=[0m2026-03-30T08:00:52.250885258Z [3mdelta[0m[2m=[0m5s 382µs 725ns ago
[INFO] [stdout] [2m2026-03-30T08:00:52.262808Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m11.651812ms [3mdelta[0m[2m=[0m5s 382µs 725ns ago
[INFO] [stdout] [2m2026-03-30T08:00:52.262832Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m response deltas sorted by latency [3mdeltas[0m[2m=[0m[-4999.982529, -4999.99988, -4999.998205, -5000.063395, -5000.382725]
[INFO] [stdout] [2m2026-03-30T08:00:52.262850Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m statistics about response deltas [3mmedian[0m[2m=[0m-4999.998205 [3mmean[0m[2m=[0m-5000.0853468000005 [3mvariance[0m[2m=[0m0.028596360641255356 [3mstddev[0m[2m=[0m0.16910458492085706
[INFO] [stdout] [2m2026-03-30T08:00:52.262868Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m eliminated outliers [3minliers[0m[2m=[0m[-4999.982529, -4999.99988, -4999.998205, -5000.063395]
[INFO] [stdout] [2m2026-03-30T08:00:52.262880Z[0m [34mDEBUG[0m [2mtimesimp[0m[2m:[0m storing calculated offset [3moffset[0m[2m=[0m5s 11µs ago
[INFO] [stdout] test server_offset_negative ... ok
[INFO] [stdout] [2m2026-03-30T08:00:52.268944Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-03-30T08:00:52.254616262Z, server: 2026-03-30T08:00:57.26253726Z } [3mcurrent[0m[2m=[0m2026-03-30T08:00:52.268752009Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m7ms 67µs 873ns [3mlocal_at_midpoint[0m[2m=[0m2026-03-30T08:00:52.261684135Z [3mdelta[0m[2m=[0m5s 853µs 125ns
[INFO] [stdout] [2m2026-03-30T08:00:52.269047Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m7.067873ms [3mdelta[0m[2m=[0m5s 853µs 125ns
[INFO] [stdout] [2m2026-03-30T08:00:52.269074Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m1.159180752s [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-03-30T08:00:52.521730Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-03-30T08:00:50.961516533Z, server: 2026-03-30T08:00:51.74147133Z } [3mcurrent[0m[2m=[0m2026-03-30T08:00:52.521535036Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m780ms 9µs 251ns [3mlocal_at_midpoint[0m[2m=[0m2026-03-30T08:00:51.741525784Z [3mdelta[0m[2m=[0m54µs 454ns ago
[INFO] [stdout] [2m2026-03-30T08:00:52.521825Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m780.009251ms [3mdelta[0m[2m=[0m54µs 454ns ago
[INFO] [stdout] [2m2026-03-30T08:00:52.521850Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m1.073884038s [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-03-30T08:00:52.647740Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-03-30T08:00:52.62507388Z, server: 2026-03-30T08:00:57.636291668Z } [3mcurrent[0m[2m=[0m2026-03-30T08:00:52.647527365Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m11ms 226µs 742ns [3mlocal_at_midpoint[0m[2m=[0m2026-03-30T08:00:52.636300622Z [3mdelta[0m[2m=[0m4s 999ms 991µs 46ns
[INFO] [stdout] [2m2026-03-30T08:00:52.647827Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m11.226742ms [3mdelta[0m[2m=[0m4s 999ms 991µs 46ns
[INFO] [stdout] [2m2026-03-30T08:00:52.647849Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m512.980868ms [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-03-30T08:00:52.746308Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-03-30T08:00:52.723688926Z, server: 2026-03-30T08:00:52.734904813Z } [3mcurrent[0m[2m=[0m2026-03-30T08:00:52.74611944Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m11ms 215µs 257ns [3mlocal_at_midpoint[0m[2m=[0m2026-03-30T08:00:52.734904183Z [3mdelta[0m[2m=[0m630ns
[INFO] [stdout] [2m2026-03-30T08:00:52.746413Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m11.215257ms [3mdelta[0m[2m=[0m630ns
[INFO] [stdout] [2m2026-03-30T08:00:52.746456Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m1.844187725s [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-03-30T08:00:52.780825Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-03-30T08:00:52.577663842Z, server: 2026-03-30T08:00:52.679188087Z } [3mcurrent[0m[2m=[0m2026-03-30T08:00:52.780616761Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m101ms 476µs 459ns [3mlocal_at_midpoint[0m[2m=[0m2026-03-30T08:00:52.679140301Z [3mdelta[0m[2m=[0m47µs 786ns
[INFO] [stdout] [2m2026-03-30T08:00:52.780939Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m101.476459ms [3mdelta[0m[2m=[0m47µs 786ns
[INFO] [stdout] [2m2026-03-30T08:00:52.780979Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m844.757802ms [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-03-30T08:00:53.137742Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-03-30T08:00:53.10954336Z, server: 2026-03-30T08:00:53.123534976Z } [3mcurrent[0m[2m=[0m2026-03-30T08:00:53.137534863Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m13ms 995µs 751ns [3mlocal_at_midpoint[0m[2m=[0m2026-03-30T08:00:53.123539111Z [3mdelta[0m[2m=[0m4µs 135ns ago
[INFO] [stdout] [2m2026-03-30T08:00:53.137839Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m13.995751ms [3mdelta[0m[2m=[0m4µs 135ns ago
[INFO] [stdout] [2m2026-03-30T08:00:53.137862Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m408.274419ms [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-03-30T08:00:53.184259Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-03-30T08:00:53.162652847Z, server: 2026-03-30T08:00:58.173858394Z } [3mcurrent[0m[2m=[0m2026-03-30T08:00:53.184068121Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m10ms 707µs 637ns [3mlocal_at_midpoint[0m[2m=[0m2026-03-30T08:00:53.173360484Z [3mdelta[0m[2m=[0m5s 497µs 910ns
[INFO] [stdout] [2m2026-03-30T08:00:53.184352Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m10.707637ms [3mdelta[0m[2m=[0m5s 497µs 910ns
[INFO] [stdout] [2m2026-03-30T08:00:53.184381Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m response deltas sorted by latency [3mdeltas[0m[2m=[0m[5000.521451, 5000.51511, 5000.49791, 4999.985041, 4999.991046]
[INFO] [stdout] [2m2026-03-30T08:00:53.184400Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m statistics about response deltas [3mmedian[0m[2m=[0m5000.49791 [3mmean[0m[2m=[0m5000.3021116 [3mvariance[0m[2m=[0m0.08227766928129114 [3mstddev[0m[2m=[0m0.28684084311912617
[INFO] [stdout] [2m2026-03-30T08:00:53.184445Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m eliminated outliers [3minliers[0m[2m=[0m[5000.521451, 5000.51511, 5000.49791]
[INFO] [stdout] [2m2026-03-30T08:00:53.184460Z[0m [34mDEBUG[0m [2mtimesimp[0m[2m:[0m storing calculated offset [3moffset[0m[2m=[0m5s 511µs
[INFO] [stdout] test low_jitter ... ok
[INFO] [stdout] [2m2026-03-30T08:00:53.371204Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-03-30T08:00:53.368713106Z, server: 2026-03-30T08:00:53.369877175Z } [3mcurrent[0m[2m=[0m2026-03-30T08:00:53.371016985Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m1ms 151µs 939ns [3mlocal_at_midpoint[0m[2m=[0m2026-03-30T08:00:53.369865045Z [3mdelta[0m[2m=[0m12µs 130ns
[INFO] [stdout] [2m2026-03-30T08:00:53.371299Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m1.151939ms [3mdelta[0m[2m=[0m12µs 130ns
[INFO] [stdout] [2m2026-03-30T08:00:53.371322Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m1.84067124s [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-03-30T08:00:53.462737Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-03-30T08:00:53.43354089Z, server: 2026-03-30T08:00:58.448864746Z } [3mcurrent[0m[2m=[0m2026-03-30T08:00:53.462533952Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m14ms 496µs 531ns [3mlocal_at_midpoint[0m[2m=[0m2026-03-30T08:00:53.448037421Z [3mdelta[0m[2m=[0m5s 827µs 325ns
[INFO] [stdout] [2m2026-03-30T08:00:53.462846Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m14.496531ms [3mdelta[0m[2m=[0m5s 827µs 325ns
[INFO] [stdout] [2m2026-03-30T08:00:53.462877Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m response deltas sorted by latency [3mdeltas[0m[2m=[0m[5000.499641, 5000.853125, 4999.963105, 4999.79284, 5000.827325]
[INFO] [stdout] [2m2026-03-30T08:00:53.462901Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m statistics about response deltas [3mmedian[0m[2m=[0m4999.963105 [3mmean[0m[2m=[0m5000.3872071999995 [3mvariance[0m[2m=[0m0.23913986952419727 [3mstddev[0m[2m=[0m0.4890192936114047
[INFO] [stdout] [2m2026-03-30T08:00:53.462928Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m eliminated outliers [3minliers[0m[2m=[0m[4999.963105, 4999.79284]
[INFO] [stdout] [2m2026-03-30T08:00:53.462941Z[0m [34mDEBUG[0m [2mtimesimp[0m[2m:[0m storing calculated offset [3moffset[0m[2m=[0m4s 999ms 877µs
[INFO] [stdout] test mid_jitter ... ok
[INFO] [stdout] [2m2026-03-30T08:00:53.570342Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-03-30T08:00:53.547710761Z, server: 2026-03-30T08:00:53.558929928Z } [3mcurrent[0m[2m=[0m2026-03-30T08:00:53.570146156Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m11ms 217µs 697ns [3mlocal_at_midpoint[0m[2m=[0m2026-03-30T08:00:53.558928458Z [3mdelta[0m[2m=[0m1µs 470ns
[INFO] [stdout] [2m2026-03-30T08:00:53.570470Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m11.217697ms [3mdelta[0m[2m=[0m1µs 470ns
[INFO] [stdout] [2m2026-03-30T08:00:53.570501Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m response deltas sorted by latency [3mdeltas[0m[2m=[0m[-0.522569, 0.00147, 1.30833, -0.824114, -0.004135]
[INFO] [stdout] [2m2026-03-30T08:00:53.570524Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m statistics about response deltas [3mmedian[0m[2m=[0m1.30833 [3mmean[0m[2m=[0m-0.0082036 [3mvariance[0m[2m=[0m0.6659130993793001 [3mstddev[0m[2m=[0m0.8160349866147285
[INFO] [stdout] [2m2026-03-30T08:00:53.570553Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m eliminated outliers [3minliers[0m[2m=[0m[1.30833]
[INFO] [stdout] [2m2026-03-30T08:00:53.570581Z[0m [34mDEBUG[0m [2mtimesimp[0m[2m:[0m storing calculated offset [3moffset[0m[2m=[0m1ms 308µs
[INFO] [stdout] test client_offset_positive ... ok
[INFO] [stdout] [2m2026-03-30T08:00:53.829577Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-03-30T08:00:53.627411721Z, server: 2026-03-30T08:00:53.727945726Z } [3mcurrent[0m[2m=[0m2026-03-30T08:00:53.829335701Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m100ms 961µs 990ns [3mlocal_at_midpoint[0m[2m=[0m2026-03-30T08:00:53.728373711Z [3mdelta[0m[2m=[0m427µs 985ns ago
[INFO] [stdout] [2m2026-03-30T08:00:53.829693Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m100.96199ms [3mdelta[0m[2m=[0m427µs 985ns ago
[INFO] [stdout] [2m2026-03-30T08:00:53.829720Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m723.547456ms [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-03-30T08:00:54.614309Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-03-30T08:00:54.591694812Z, server: 2026-03-30T08:00:54.602906839Z } [3mcurrent[0m[2m=[0m2026-03-30T08:00:54.614114466Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m11ms 209µs 827ns [3mlocal_at_midpoint[0m[2m=[0m2026-03-30T08:00:54.602904639Z [3mdelta[0m[2m=[0m2µs 200ns
[INFO] [stdout] [2m2026-03-30T08:00:54.614400Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m11.209827ms [3mdelta[0m[2m=[0m2µs 200ns
[INFO] [stdout] [2m2026-03-30T08:00:54.614445Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m response deltas sorted by latency [3mdeltas[0m[2m=[0m[0.0022, 0.00063, -0.005195, 0.359105, -1.333294]
[INFO] [stdout] [2m2026-03-30T08:00:54.614466Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m statistics about response deltas [3mmedian[0m[2m=[0m-0.005195 [3mmean[0m[2m=[0m-0.19531079999999998 [3mvariance[0m[2m=[0m0.42898249335070004 [3mstddev[0m[2m=[0m0.6549675513723562
[INFO] [stdout] [2m2026-03-30T08:00:54.614488Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m eliminated outliers [3minliers[0m[2m=[0m[0.0022, 0.00063, -0.005195, 0.359105]
[INFO] [stdout] [2m2026-03-30T08:00:54.614500Z[0m [34mDEBUG[0m [2mtimesimp[0m[2m:[0m storing calculated offset [3moffset[0m[2m=[0m89µs
[INFO] [stdout] test client_offset_negative ... ok
[INFO] [stdout] [2m2026-03-30T08:00:54.757726Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-03-30T08:00:54.554691941Z, server: 2026-03-30T08:00:54.656168616Z } [3mcurrent[0m[2m=[0m2026-03-30T08:00:54.757528261Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m101ms 418µs 160ns [3mlocal_at_midpoint[0m[2m=[0m2026-03-30T08:00:54.656110101Z [3mdelta[0m[2m=[0m58µs 515ns
[INFO] [stdout] [2m2026-03-30T08:00:54.757845Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m101.41816ms [3mdelta[0m[2m=[0m58µs 515ns
[INFO] [stdout] [2m2026-03-30T08:00:54.757874Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m response deltas sorted by latency [3mdeltas[0m[2m=[0m[-0.526995, -0.427985, 0.058515, 0.047786, -0.488624]
[INFO] [stdout] [2m2026-03-30T08:00:54.757894Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m statistics about response deltas [3mmedian[0m[2m=[0m0.058515 [3mmean[0m[2m=[0m-0.2674606 [3mvariance[0m[2m=[0m0.0869199869713 [3mstddev[0m[2m=[0m0.29482195808877604
[INFO] [stdout] [2m2026-03-30T08:00:54.757918Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m eliminated outliers [3minliers[0m[2m=[0m[0.058515, 0.047786]
[INFO] [stdout] [2m2026-03-30T08:00:54.757937Z[0m [34mDEBUG[0m [2mtimesimp[0m[2m:[0m storing calculated offset [3moffset[0m[2m=[0m53µs
[INFO] [stdout] test some_delay ... ok
[INFO] [stdout] [2m2026-03-30T08:00:55.215176Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-03-30T08:00:55.212693408Z, server: 2026-03-30T08:00:55.213849888Z } [3mcurrent[0m[2m=[0m2026-03-30T08:00:55.215000967Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m1ms 153µs 779ns [3mlocal_at_midpoint[0m[2m=[0m2026-03-30T08:00:55.213847187Z [3mdelta[0m[2m=[0m2µs 701ns
[INFO] [stdout] [2m2026-03-30T08:00:55.215270Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m1.153779ms [3mdelta[0m[2m=[0m2µs 701ns
[INFO] [stdout] [2m2026-03-30T08:00:55.215296Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m response deltas sorted by latency [3mdeltas[0m[2m=[0m[0.009401, 0.01213, 0.002701, -0.03816, 1.441769]
[INFO] [stdout] [2m2026-03-30T08:00:55.215320Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m statistics about response deltas [3mmedian[0m[2m=[0m0.002701 [3mmean[0m[2m=[0m0.28556820000000005 [3mvariance[0m[2m=[0m0.41816271545170014 [3mstddev[0m[2m=[0m0.6466550204333839
[INFO] [stdout] [2m2026-03-30T08:00:55.215354Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m eliminated outliers [3minliers[0m[2m=[0m[0.009401, 0.01213, 0.002701, -0.03816]
[INFO] [stdout] [2m2026-03-30T08:00:55.215367Z[0m [34mDEBUG[0m [2mtimesimp[0m[2m:[0m storing calculated offset [3moffset[0m[2m=[0m3µs ago
[INFO] [stdout] test no_delay ... ok
[INFO] [stdout] [2m2026-03-30T08:00:55.502760Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-03-30T08:00:53.597155989Z, server: 2026-03-30T08:00:54.547724753Z } [3mcurrent[0m[2m=[0m2026-03-30T08:00:55.502538976Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m952ms 691µs 493ns [3mlocal_at_midpoint[0m[2m=[0m2026-03-30T08:00:54.549847482Z [3mdelta[0m[2m=[0m2ms 122µs 729ns ago
[INFO] [stdout] [2m2026-03-30T08:00:55.502880Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m952.691493ms [3mdelta[0m[2m=[0m2ms 122µs 729ns ago
[INFO] [stdout] [2m2026-03-30T08:00:55.502906Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m1.953963761s [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-03-30T08:00:59.011733Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-03-30T08:00:57.457994151Z, server: 2026-03-30T08:00:58.231692548Z } [3mcurrent[0m[2m=[0m2026-03-30T08:00:59.011529735Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m776ms 767µs 792ns [3mlocal_at_midpoint[0m[2m=[0m2026-03-30T08:00:58.234761943Z [3mdelta[0m[2m=[0m3ms 69µs 395ns ago
[INFO] [stdout] [2m2026-03-30T08:00:59.011821Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m776.767792ms [3mdelta[0m[2m=[0m3ms 69µs 395ns ago
[INFO] [stdout] [2m2026-03-30T08:00:59.011844Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m58.682527ms [3mmax_jitter[0m[2m=[0m2s
[INFO] [stderr]      Running tests/in_process.rs (/opt/rustwide/target/debug/deps/in_process-ec9e0f69263559fc)
[INFO] [stdout] [2m2026-03-30T08:01:00.897905Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-03-30T08:00:59.07122131Z, server: 2026-03-30T08:00:59.984696753Z } [3mcurrent[0m[2m=[0m2026-03-30T08:01:00.897692067Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m913ms 235µs 378ns [3mlocal_at_midpoint[0m[2m=[0m2026-03-30T08:00:59.984456688Z [3mdelta[0m[2m=[0m240µs 65ns
[INFO] [stdout] [2m2026-03-30T08:01:00.898016Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m913.235378ms [3mdelta[0m[2m=[0m240µs 65ns
[INFO] [stdout] [2m2026-03-30T08:01:00.898048Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m response deltas sorted by latency [3mdeltas[0m[2m=[0m[-3.069395, -0.054454, 0.240065, 0.35135, -2.122729]
[INFO] [stdout] [2m2026-03-30T08:01:00.898073Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m statistics about response deltas [3mmedian[0m[2m=[0m0.240065 [3mmean[0m[2m=[0m-0.9310326 [3mvariance[0m[2m=[0m2.4442747067483 [3mstddev[0m[2m=[0m1.5634176367011792
[INFO] [stdout] [2m2026-03-30T08:01:00.898106Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m eliminated outliers [3minliers[0m[2m=[0m[-0.054454, 0.240065, 0.35135]
[INFO] [stdout] [2m2026-03-30T08:01:00.898121Z[0m [34mDEBUG[0m [2mtimesimp[0m[2m:[0m storing calculated offset [3moffset[0m[2m=[0m178µs
[INFO] [stdout] test much_delay ... ok
[INFO] [stdout] 
[INFO] [stdout] test result: ok. 10 passed; 0 failed; 0 ignored; 0 measured; 0 filtered out; finished in 11.85s
[INFO] [stdout] 
[INFO] [stdout] 
[INFO] [stdout] running 4 tests
[INFO] [stdout] [2m2026-03-30T08:01:00.914853Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m starting delta collection [3msamples[0m[2m=[0m5 [3mcurrent_offset[0m[2m=[0m5s ago
[INFO] [stdout] [2m2026-03-30T08:01:00.914909Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m starting delta collection [3msamples[0m[2m=[0m5 [3mcurrent_offset[0m[2m=[0m5s
[INFO] [stdout] [2m2026-03-30T08:01:00.916247Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m0ns [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-03-30T08:01:00.914987Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m starting delta collection [3msamples[0m[2m=[0m5 [3mcurrent_offset[0m[2m=[0m0s
[INFO] [stdout] [2m2026-03-30T08:01:00.916292Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m0ns [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-03-30T08:01:00.915024Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m starting delta collection [3msamples[0m[2m=[0m5 [3mcurrent_offset[0m[2m=[0m0s
[INFO] [stdout] [2m2026-03-30T08:01:00.916375Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m0ns [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-03-30T08:01:00.916414Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m0ns [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-03-30T08:01:00.918467Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-03-30T08:01:00.918200362Z, server: 2026-03-30T08:01:05.918228992Z } [3mcurrent[0m[2m=[0m2026-03-30T08:01:00.918233192Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m16µs 415ns [3mlocal_at_midpoint[0m[2m=[0m2026-03-30T08:01:00.918216777Z [3mdelta[0m[2m=[0m5s 12µs 215ns
[INFO] [stdout] [2m2026-03-30T08:01:00.918577Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m16.415µs [3mdelta[0m[2m=[0m5s 12µs 215ns
[INFO] [stdout] [2m2026-03-30T08:01:00.918599Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m743.724219ms [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-03-30T08:01:00.918652Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-03-30T08:01:00.918542302Z, server: 2026-03-30T08:01:00.918545832Z } [3mcurrent[0m[2m=[0m2026-03-30T08:01:00.918547742Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m2µs 720ns [3mlocal_at_midpoint[0m[2m=[0m2026-03-30T08:01:00.918545022Z [3mdelta[0m[2m=[0m810ns
[INFO] [stdout] [2m2026-03-30T08:01:00.918714Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m2.72µs [3mdelta[0m[2m=[0m810ns
[INFO] [stdout] [2m2026-03-30T08:01:00.918758Z[0m [34mDEBUG[0m [2mtimesimp[0m[2m:[0m no offset stored, storing initial delta [3moffset[0m[2m=[0m810ns
[INFO] [stdout] [2m2026-03-30T08:01:00.918772Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m407.623956ms [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-03-30T08:01:00.918768Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-03-30T08:01:00.918659561Z, server: 2026-03-30T08:01:00.918663352Z } [3mcurrent[0m[2m=[0m2026-03-30T08:01:00.918665341Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m2µs 890ns [3mlocal_at_midpoint[0m[2m=[0m2026-03-30T08:01:00.918662451Z [3mdelta[0m[2m=[0m901ns
[INFO] [stdout] [2m2026-03-30T08:01:00.918821Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m2.89µs [3mdelta[0m[2m=[0m901ns
[INFO] [stdout] [2m2026-03-30T08:01:00.918474Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-03-30T08:01:00.918170272Z, server: 2026-03-30T08:00:55.918224672Z } [3mcurrent[0m[2m=[0m2026-03-30T08:01:00.918229092Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m29µs 410ns [3mlocal_at_midpoint[0m[2m=[0m2026-03-30T08:01:00.918199682Z [3mdelta[0m[2m=[0m4s 999ms 975µs 10ns ago
[INFO] [stdout] [2m2026-03-30T08:01:00.918838Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m1.479557675s [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-03-30T08:01:00.918862Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m29.41µs [3mdelta[0m[2m=[0m4s 999ms 975µs 10ns ago
[INFO] [stdout] [2m2026-03-30T08:01:00.918887Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m179.863001ms [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-03-30T08:01:01.100575Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-03-30T08:01:01.100339836Z, server: 2026-03-30T08:00:56.100352196Z } [3mcurrent[0m[2m=[0m2026-03-30T08:01:01.100357016Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m8µs 590ns [3mlocal_at_midpoint[0m[2m=[0m2026-03-30T08:01:01.100348426Z [3mdelta[0m[2m=[0m4s 999ms 996µs 230ns ago
[INFO] [stdout] [2m2026-03-30T08:01:01.100683Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m8.59µs [3mdelta[0m[2m=[0m4s 999ms 996µs 230ns ago
[INFO] [stdout] [2m2026-03-30T08:01:01.100709Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m1.406441845s [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-03-30T08:01:01.327737Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-03-30T08:01:01.32750583Z, server: 2026-03-30T08:01:01.32751949Z } [3mcurrent[0m[2m=[0m2026-03-30T08:01:01.32752321Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m8µs 690ns [3mlocal_at_midpoint[0m[2m=[0m2026-03-30T08:01:01.32751452Z [3mdelta[0m[2m=[0m4µs 970ns
[INFO] [stdout] [2m2026-03-30T08:01:01.327830Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m8.69µs [3mdelta[0m[2m=[0m4µs 970ns
[INFO] [stdout] [2m2026-03-30T08:01:01.327849Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m1.561447042s [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-03-30T08:01:01.663838Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-03-30T08:01:01.663641207Z, server: 2026-03-30T08:01:06.663652787Z } [3mcurrent[0m[2m=[0m2026-03-30T08:01:01.663656717Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m7µs 755ns [3mlocal_at_midpoint[0m[2m=[0m2026-03-30T08:01:01.663648962Z [3mdelta[0m[2m=[0m5s 3µs 825ns
[INFO] [stdout] [2m2026-03-30T08:01:01.663929Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m7.755µs [3mdelta[0m[2m=[0m5s 3µs 825ns
[INFO] [stdout] [2m2026-03-30T08:01:01.663950Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m1.262630274s [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-03-30T08:01:02.401738Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-03-30T08:01:02.401531774Z, server: 2026-03-30T08:01:02.401542914Z } [3mcurrent[0m[2m=[0m2026-03-30T08:01:02.401547654Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m7µs 940ns [3mlocal_at_midpoint[0m[2m=[0m2026-03-30T08:01:02.401539714Z [3mdelta[0m[2m=[0m3µs 200ns
[INFO] [stdout] [2m2026-03-30T08:01:02.401929Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m7.94µs [3mdelta[0m[2m=[0m3µs 200ns
[INFO] [stdout] [2m2026-03-30T08:01:02.402009Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m1.544241054s [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-03-30T08:01:02.508942Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-03-30T08:01:02.508734637Z, server: 2026-03-30T08:00:57.508746367Z } [3mcurrent[0m[2m=[0m2026-03-30T08:01:02.508750437Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m7µs 900ns [3mlocal_at_midpoint[0m[2m=[0m2026-03-30T08:01:02.508742537Z [3mdelta[0m[2m=[0m4s 999ms 996µs 170ns ago
[INFO] [stdout] [2m2026-03-30T08:01:02.509067Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m7.9µs [3mdelta[0m[2m=[0m4s 999ms 996µs 170ns ago
[INFO] [stdout] [2m2026-03-30T08:01:02.509091Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m1.745329629s [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-03-30T08:01:02.890982Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-03-30T08:01:02.890766042Z, server: 2026-03-30T08:01:02.890779772Z } [3mcurrent[0m[2m=[0m2026-03-30T08:01:02.890783312Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m8µs 635ns [3mlocal_at_midpoint[0m[2m=[0m2026-03-30T08:01:02.890774677Z [3mdelta[0m[2m=[0m5µs 95ns
[INFO] [stdout] [2m2026-03-30T08:01:02.891090Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m8.635µs [3mdelta[0m[2m=[0m5µs 95ns
[INFO] [stdout] [2m2026-03-30T08:01:02.891115Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m1.278198598s [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-03-30T08:01:02.927964Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-03-30T08:01:02.927725703Z, server: 2026-03-30T08:01:07.927738463Z } [3mcurrent[0m[2m=[0m2026-03-30T08:01:02.927743123Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m8µs 710ns [3mlocal_at_midpoint[0m[2m=[0m2026-03-30T08:01:02.927734413Z [3mdelta[0m[2m=[0m5s 4µs 50ns
[INFO] [stdout] [2m2026-03-30T08:01:02.928148Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m8.71µs [3mdelta[0m[2m=[0m5s 4µs 50ns
[INFO] [stdout] [2m2026-03-30T08:01:02.928217Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m263.285269ms [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-03-30T08:01:03.192915Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-03-30T08:01:03.192717267Z, server: 2026-03-30T08:01:08.192729067Z } [3mcurrent[0m[2m=[0m2026-03-30T08:01:03.192733437Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m8µs 85ns [3mlocal_at_midpoint[0m[2m=[0m2026-03-30T08:01:03.192725352Z [3mdelta[0m[2m=[0m5s 3µs 715ns
[INFO] [stdout] [2m2026-03-30T08:01:03.193113Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m8.085µs [3mdelta[0m[2m=[0m5s 3µs 715ns
[INFO] [stdout] [2m2026-03-30T08:01:03.193192Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m491.402431ms [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-03-30T08:01:03.685900Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-03-30T08:01:03.685700405Z, server: 2026-03-30T08:01:08.685712455Z } [3mcurrent[0m[2m=[0m2026-03-30T08:01:03.685716905Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m8µs 250ns [3mlocal_at_midpoint[0m[2m=[0m2026-03-30T08:01:03.685708655Z [3mdelta[0m[2m=[0m5s 3µs 800ns
[INFO] [stdout] [2m2026-03-30T08:01:03.686107Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m8.25µs [3mdelta[0m[2m=[0m5s 3µs 800ns
[INFO] [stdout] [2m2026-03-30T08:01:03.686241Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m response deltas sorted by latency [3mdeltas[0m[2m=[0m[5000.003825, 5000.003715, 5000.0038, 5000.00405, 5000.012215]
[INFO] [stdout] [2m2026-03-30T08:01:03.686321Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m statistics about response deltas [3mmedian[0m[2m=[0m5000.0038 [3mmean[0m[2m=[0m5000.005521 [3mvariance[0m[2m=[0m1.4018342499454339e-5 [3mstddev[0m[2m=[0m0.003744107704040355
[INFO] [stdout] [2m2026-03-30T08:01:03.686391Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m eliminated outliers [3minliers[0m[2m=[0m[5000.003825, 5000.003715, 5000.0038, 5000.00405]
[INFO] [stdout] [2m2026-03-30T08:01:03.686457Z[0m [34mDEBUG[0m [2mtimesimp[0m[2m:[0m storing calculated offset [3moffset[0m[2m=[0m5s 3µs
[INFO] [stdout] test positive_starting_offset ... ok
[INFO] [stdout] [2m2026-03-30T08:01:03.955726Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-03-30T08:01:03.955537498Z, server: 2026-03-30T08:01:03.955551128Z } [3mcurrent[0m[2m=[0m2026-03-30T08:01:03.955554978Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m8µs 740ns [3mlocal_at_midpoint[0m[2m=[0m2026-03-30T08:01:03.955546238Z [3mdelta[0m[2m=[0m4µs 890ns
[INFO] [stdout] [2m2026-03-30T08:01:03.955809Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m8.74µs [3mdelta[0m[2m=[0m4µs 890ns
[INFO] [stdout] [2m2026-03-30T08:01:03.955827Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m1.878906166s [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-03-30T08:01:04.170899Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-03-30T08:01:04.170703854Z, server: 2026-03-30T08:01:04.170716784Z } [3mcurrent[0m[2m=[0m2026-03-30T08:01:04.170720754Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m8µs 450ns [3mlocal_at_midpoint[0m[2m=[0m2026-03-30T08:01:04.170712304Z [3mdelta[0m[2m=[0m4µs 480ns
[INFO] [stdout] [2m2026-03-30T08:01:04.170997Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m8.45µs [3mdelta[0m[2m=[0m4µs 480ns
[INFO] [stdout] [2m2026-03-30T08:01:04.171018Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m367.856147ms [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-03-30T08:01:04.255892Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-03-30T08:01:04.255687963Z, server: 2026-03-30T08:00:59.255700133Z } [3mcurrent[0m[2m=[0m2026-03-30T08:01:04.255704643Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m8µs 340ns [3mlocal_at_midpoint[0m[2m=[0m2026-03-30T08:01:04.255696303Z [3mdelta[0m[2m=[0m4s 999ms 996µs 170ns ago
[INFO] [stdout] [2m2026-03-30T08:01:04.256009Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m8.34µs [3mdelta[0m[2m=[0m4s 999ms 996µs 170ns ago
[INFO] [stdout] [2m2026-03-30T08:01:04.256032Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m544.346775ms [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-03-30T08:01:04.539918Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-03-30T08:01:04.539690713Z, server: 2026-03-30T08:01:04.539704213Z } [3mcurrent[0m[2m=[0m2026-03-30T08:01:04.539707953Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m8µs 620ns [3mlocal_at_midpoint[0m[2m=[0m2026-03-30T08:01:04.539699333Z [3mdelta[0m[2m=[0m4µs 880ns
[INFO] [stdout] [2m2026-03-30T08:01:04.540034Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m8.62µs [3mdelta[0m[2m=[0m4µs 880ns
[INFO] [stdout] [2m2026-03-30T08:01:04.540066Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m response deltas sorted by latency [3mdeltas[0m[2m=[0m[0.00081, 0.00448, 0.00488, 0.005095, 0.00497]
[INFO] [stdout] [2m2026-03-30T08:01:04.540087Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m statistics about response deltas [3mmedian[0m[2m=[0m0.00488 [3mmean[0m[2m=[0m0.004046999999999999 [3mvariance[0m[2m=[0m3.327444999999999e-6 [3mstddev[0m[2m=[0m0.0018241285590659445
[INFO] [stdout] [2m2026-03-30T08:01:04.540109Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m eliminated outliers [3minliers[0m[2m=[0m[0.00448, 0.00488, 0.005095, 0.00497]
[INFO] [stdout] [2m2026-03-30T08:01:04.540122Z[0m [34mDEBUG[0m [2mtimesimp[0m[2m:[0m storing calculated offset [3moffset[0m[2m=[0m4µs
[INFO] [stdout] test null_offset ... ok
[INFO] [stdout] [2m2026-03-30T08:01:04.805749Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-03-30T08:01:04.805551827Z, server: 2026-03-30T08:00:59.805564537Z } [3mcurrent[0m[2m=[0m2026-03-30T08:01:04.805568787Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m8µs 480ns [3mlocal_at_midpoint[0m[2m=[0m2026-03-30T08:01:04.805560307Z [3mdelta[0m[2m=[0m4s 999ms 995µs 770ns ago
[INFO] [stdout] [2m2026-03-30T08:01:04.805854Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m8.48µs [3mdelta[0m[2m=[0m4s 999ms 995µs 770ns ago
[INFO] [stdout] [2m2026-03-30T08:01:04.805884Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m response deltas sorted by latency [3mdeltas[0m[2m=[0m[-4999.99617, -4999.99617, -4999.9957699999995, -4999.99623, -4999.97501]
[INFO] [stdout] [2m2026-03-30T08:01:04.805904Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m statistics about response deltas [3mmedian[0m[2m=[0m-4999.9957699999995 [3mmean[0m[2m=[0m-4999.99187 [3mvariance[0m[2m=[0m8.88647999990929e-5 [3mstddev[0m[2m=[0m0.009426812822958399
[INFO] [stdout] [2m2026-03-30T08:01:04.805924Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m eliminated outliers [3minliers[0m[2m=[0m[-4999.99617, -4999.99617, -4999.9957699999995, -4999.99623]
[INFO] [stdout] [2m2026-03-30T08:01:04.805948Z[0m [34mDEBUG[0m [2mtimesimp[0m[2m:[0m storing calculated offset [3moffset[0m[2m=[0m4s 999ms 996µs ago
[INFO] [stdout] test negative_starting_offset ... ok
[INFO] [stdout] [2m2026-03-30T08:01:05.835794Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-03-30T08:01:05.835560391Z, server: 2026-03-30T08:01:05.835574021Z } [3mcurrent[0m[2m=[0m2026-03-30T08:01:05.835578691Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m9µs 150ns [3mlocal_at_midpoint[0m[2m=[0m2026-03-30T08:01:05.835569541Z [3mdelta[0m[2m=[0m4µs 480ns
[INFO] [stdout] [2m2026-03-30T08:01:05.836012Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m9.15µs [3mdelta[0m[2m=[0m4µs 480ns
[INFO] [stderr]    Doc-tests timesimp
[INFO] [stdout] [2m2026-03-30T08:01:05.836119Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m2.085098ms [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-03-30T08:01:05.839545Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-03-30T08:01:05.83946298Z, server: 2026-03-30T08:01:05.83946661Z } [3mcurrent[0m[2m=[0m2026-03-30T08:01:05.83946828Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m2µs 650ns [3mlocal_at_midpoint[0m[2m=[0m2026-03-30T08:01:05.83946563Z [3mdelta[0m[2m=[0m980ns
[INFO] [stdout] [2m2026-03-30T08:01:05.839657Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m2.65µs [3mdelta[0m[2m=[0m980ns
[INFO] [stdout] [2m2026-03-30T08:01:05.839723Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m response deltas sorted by latency [3mdeltas[0m[2m=[0m[0.00098, 0.000901, 0.0032, 0.00489, 0.00448]
[INFO] [stdout] [2m2026-03-30T08:01:05.839780Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m statistics about response deltas [3mmedian[0m[2m=[0m0.0032 [3mmean[0m[2m=[0m0.0028902 [3mvariance[0m[2m=[0m3.5571052000000004e-6 [3mstddev[0m[2m=[0m0.0018860289499368775
[INFO] [stdout] [2m2026-03-30T08:01:05.839817Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m eliminated outliers [3minliers[0m[2m=[0m[0.0032, 0.00489, 0.00448]
[INFO] [stdout] [2m2026-03-30T08:01:05.839874Z[0m [34mDEBUG[0m [2mtimesimp[0m[2m:[0m storing calculated offset [3moffset[0m[2m=[0m4µs
[INFO] [stdout] test zero_offset ... ok
[INFO] [stdout] 
[INFO] [stdout] test result: ok. 4 passed; 0 failed; 0 ignored; 0 measured; 0 filtered out; finished in 4.93s
[INFO] [stdout] 
[INFO] [stdout] 
[INFO] [stdout] running 2 tests
[INFO] [stdout] test src/lib.rs - Timesimp::attempt_sync (line 220) ... ignored
[INFO] [stdout] test src/lib.rs - (line 24) - compile ... ok
[INFO] [stdout] 
[INFO] [stdout] test result: ok. 1 passed; 0 failed; 1 ignored; 0 measured; 0 filtered out; finished in 0.00s
[INFO] [stdout] 
[INFO] [stdout] all doctests ran in 2.04s; merged doctests compilation took 1.88s
[INFO] running `Command { std: "docker" "inspect" "19120db81d8a1a38732d42a9108bbb5ee1881eeba61799936b71c5cb6431180f", kill_on_drop: false }`
[INFO] running `Command { std: "docker" "rm" "-f" "19120db81d8a1a38732d42a9108bbb5ee1881eeba61799936b71c5cb6431180f", kill_on_drop: false }`
[INFO] [stdout] 19120db81d8a1a38732d42a9108bbb5ee1881eeba61799936b71c5cb6431180f
